[PoC] Add structlog for structured logging - #587

why removing this one? It is highly useful to understand where/how a given vm uuid gets used in the test flow

It's not removed, it's moved to the __init__ methods of VM and Snapshot, since they both use a different logger:

        self.logger = structlog.get_logger("VM").bind(
            pool=host.pool.master_hostname_or_ip,
            host=host.hostname_or_ip,
            vm_uuid=uuid
        )
        super().__init__(uuid, host)
        self.logger.info("New VM instantiated")

https://github.com/xcp-ng/xcp-ng-tests/pull/587/changes#diff-837c65b110297a236fe570228cc454e0360a5c3b8f2febe709b14e68eb5592dfR45

the success of a command is implied by the lack of immediate error, why adding this?

I figured it'd be useful information, since no log would either mean that the command succeeded or that the command is still running. With this debug log, we get a timestamp for when the command actually returned.

looks like there were too many infos in that original log, we only need a log in case of error here. And that should not be a "debug" one.

But fixing that kind of things would belong to a preliminar separate fix, so this commit would only really be a conversion, there is enough to read in there already

But fixing that kind of things would belong to a preliminar separate fix, so this commit would only really be a conversion, there is enough to read in there already

Sure. This is a proof of concept and the commit is not meant to be integrated as it is now. For instance, there are still many use of logging in the code base. The point here is to show what improved logging could look like.

As I went through the code in lib/commands, I noticed a lack of consistency on how the command logs are managed (since I assume that SSH, SCP and local commands should provided the same logs for when the command is started and when it returned). So that change is a way to show what consistent logs for those three kinds of commands would look like.

And that should not be a "debug" one.

I agree.

The issue I have with this, is the essential info is the command. Having the main log read "Run local command" and having to dig in all the following attributes is counter-productive

I both agree and disagree.

For instance take the following SSH command, performed in Host.rescan_block_devices_info:

'lsblk --pairs --bytes --output NAME,KNAME,PKNAME,SIZE,LOG-SEC,TYPE,MOUNTPOINT,WWN --include 8,9,65,66,67,68,69,70,71,128,129,130,131,132,133,134,135,252,253,259'

Having this command in bright in the log message would impact readability. In structured logging, we usually want the log message to be a short string describing the event that occurred. This example can actually be seen in the before/after comparison in the debug log section of this PR description.

That being said, I also agree that the command is an important part of this log and we could benefit from having a custom formater for it. For instance, we could have the command keys always stand out more than the other ones. This is similar to the idea of using custom formater for the VM, Pool , Host and Snapshot loggers that I mentioned earlier: some of their context is more important than the rest, and could be formatted in a way that makes it more obvious.

Quick digression: note how structured logging promotes a separation of concerns here:

• the producer is responsible for providing a clear message with all the relevant context as key-values
• the consumer is then responsible for making the most out of this structured data.

This is especially important for systems where there are several consumers for the logs. Imagine we start sending the jenkins logs to a log database (with the ELK stack or similar). Then it's very useful for our logs to be structured, so that we can configure all kinds of filters in the interface. On the other hand, we don't want to the console to show a json dict for each log as this would not be readable. So in this case, the responsibility of the log consumer for the console is to use the context to provide the most readable output for the terminal.

The important question is who you format the logs for. The ones who actually dig into test logs will need to be involved.

Especially for SSH commands, which are the majority of what happens in debug logs, we have some kind of structure. You have the IP address of the target, and the command. Then the result. In your proposal I find the useful information less visible. I don't think it would be very interesting to have. If you want to indentify a kind of operation, you could use a single letter (S for SSH, L for local), but leave the description for what really describes what's going on.

I also agree that "command succesful" logs are probably not useful for what we use the logs for.

Having this command in bright in the log message would impact readability.

Compared to what? We already have them right in the logs, along with the IP address of the target and the output, and if there's something that's really readable in our logs, this would be it.

In structured logging, we usually want the log message to be a short string describing the event that occurred.

Here, the main problem is you haven't described what structured logging is for and what needs it addresses, and why this is pertinent in our case (not production log: test logs). So I don't know yet if this "we" is us here. Failing to explain that, the benefits are not obvious, and the drawbacks pointed by Yann, who'd affect maybe 90% of the debug logs, are. SSH commands are the most common thing we do in the tests. We want it to be readable without contorsion.

The important question is who you format the logs for. The ones who actually dig into test logs will need to be involved.

Yes that's the scope of this PR, gather feedback from the team. The description has been updated to reflect this.

Especially for SSH commands, which are the majority of what happens in debug logs, we have some kind of structure. You have the IP address of the target, and the command

I added this constraint in the documentation and updated the screenshots.

I also agree that "command successful" logs are probably not useful for what we use the logs for.

This doesn't have to part of this proposal, and it's something that we can add later if we feel the need to do so. Still I can elaborate a bit more on my reasoning here. In a production system, it's very common to produce a specific log when a command or a request returns successfully. The first reason for that is to not rely on the absence of an error log, or the timestamp of a subsequent one. The other reason is that more information can be included the event dictionary such as the elapsed time of the command. This can be useful when storing the logs in a database and processing them, since it can easily answer questions such as "which command is the slowest" or "is a machine significantly slower than the rest".

Compared to what? We already have them right in the logs, along with the IP address of the target and the output, and if there's something that's really readable in our logs, this would be it.

Sorry I meant bold not bright, as in CSI 1 n

Currently our logs are just plain white, while structlog shows the event message in bold white. My point is that interpolating the command in the event message would impact readability since those messages are meant to standout so we can easily find the event we're looking for. My suggestion in this case would be to use a custom renderer specifically for SSH commands that use different colors to make sure such commands stand out as a separate thing. I updated the screenshots with an exemple of what such custom renderers could look like.

Here, the main problem is you haven't described what structured logging is for and what needs it addresses, and why this is pertinent in our case (not production log: test logs).

I updated the description to provide some reference explaining what structured logging is. Also you make an interesting point: is structured logging also meaningful in our test context, compared to the typical usage of gathering logs in a production server. This question should be discussed with the team, but I have two ideas that can be explored:

• First, our jenkins CI constantly running tests in the lab is not too far from a production environment. If we use structured logging, would could start to store all the logs produced by jenkins in a database so that we can process them later. Obviously, we would configure the log handler to include all kinds of information about the jenkins job in the emitted logs (the xcp-ng-tests commit hash for instance), so that they can be filtered and compared. For instance, consider the "which command is the slowest" example from one of my earlier comment. More generally, structured logging opens the way for more automation.
• Second, the code in ./lib is also going to be used by the "Lab as a service" project developed by @olivierh-pro and @clem-v-irt. This usage might be closer to production logging than test logging.

I like that it's structured and prettified and simplifies logging concerns for developers when they write tests or libs for the tests. I really dislike how large it becomes, however. Do you always run tests on very large screens? Here's where I run tests, because I split my terminal between several topics, and I'm pretty sure I'm not the only one who doesn't have such horizontal space for all the extra information:

I've also read a lot of tests results in Jenkins, in screen, or shared on matrix (!!). I think something that large is just a no-go. But there's probably a way to make it shorter while remaining more structured.

It's not entirely clear to me what need you address. That's the difficulty with such POCs, though it's good you made it a draft so that it's clear that there's no hurry with it. I still feel summoned to comment because I can see how it can look nice and pretty if you don't consider the needs I exposed above, so in a way I still appreciate this form of POC less than an actual design document that discusses separatetly, first, the needs, the problem you want to solve, and then only comes with a proposition to discuss if the exposed needs are agreed upon (this can be done at the same time, as I understand that you want to illustrate with real examples of what it could look like, but separating the discussion of the needs and the proposed solution remains a practice I really would like to see generalized.

I can see automated tools happy to find that kind of extra information on each log line. For humans, it can be useful sometimes, but comes at a high cost, the cost of having to ignore meaningless information all over the place and lines that almost require a 4K screen, and possibly go fetch what used to be directly in front of their eyes to a distant place on the right.

A few suggestions for a compromise:

1. Offer several presentations. But I'd push for the default one to keep fitting in a small screen.
2. The main flaw in the proposed presentation is that any large log entry pushes everything to the right. So then you have to move the large piece of information to a separate entry to keep the main entry short... But the main entry becomes meaningless. I suggest to stuff a minimal amount of very important information BEFORE the actual message. Then optionnally more information in non-compact mode.
3. Find a way to describe objects with shorter string. For a UUID, I'm pretty sure we can do with the 8 first characters, as humans (and still display the full UUID as a normal message when the VM is imported). Non-compact mode can have the full IDs.

Example:

Jun 19 23:34:29.598 [I][VM       45fecdef] Shutdown VM (force)
Jun 19 23:34:29.598 [D][VM    10.1.16.203] date
Jun 19 23:34:29.598 [D] > [output of the command]
Jun 19 23:34:29.598 [D][Host   10.1.14.86] xe vm-shutdown uuid=5ee9365a-94ca-b008-3223-ed2cb30c6725 force=true
Jun 19 23:34:36.070 [D][Host   10.1.14.86] xe vm-disk-list --minimal  uuid=5ee9365a-94ca-b008-3223-ed2cb30c6725 vbd-params=''
Jun 19 23:34:36.247 [D] > 39971b17-510b-44fd-87b0-3d30ad840acc

More information coming from the structured logs, such as the host IP for the first INFO line, could be appended optionnally.

(I kept the notion of SSH implicit for now, but we could add SSH: before the commands. By the way the object is not "ssh" in my case, it's the target of the SSH command, so a Host or a VM.)

I haven't looked closely at the rich tracebacks. To be evaluated in situations that reproduce errors we've already had, to see if it's an obvious improvement... Or not. Including complex cases such as exception raised an exception, or fixture teardown failed... Topics that I raise now but that I would prefer to see considered directly from the "what's the problem we want to solve" phase rather than as a review comment on a POC.

All the above being written, such a change, IMO, necessitates planning. We're late on the planning for the new ISO images. We have a lot of updates to build and test for XCP-ng. Flaky tests to stabilize. Lots of reviews. A new release of XCP-ng. All of theses are planned items. As good as the intentions behind this proposal are, it shifts the attention from these.

In other words, this seems too big a change, too pervasive, to come unplanned, and mobilize the platform team right now.

After a discussion with @stormi, it was decided that work on this PR can continue as long as it is clear that its scope is to gather feedback with the objective of writing a design document that would then have to be:

1. validated with the team
2. planned as a work item
3. implemented in a different PR

I really dislike how large it becomes, however. Do you always run tests on very large screens?

It depends, but yes I took the original screenshots in a large window to show all the information included in a given log on a single line. In practice, screens would indeed be much smaller and some logs would span over several lines. To avoid this confusion, I updated most the screenshots to match the 120-column terminal shown in your screenshot.

Also, I've updated the description to add a key constraint for the structlog migration: the logs must remain just as readable in 120-column terminal. One way to address this constraint is to use custom renderers for the pool, host, VM and snapshot loggers. I added a couple of screenshots to illustrate how it could like (in particular, I kept the most important information in an identifier column while filtering out the rest).

For humans, it can be useful sometimes, but comes at a high cost, the cost of having to ignore meaningless information all over the place and lines that almost require a 4K screen, and possibly go fetch what used to be directly in front of their eyes to a distant place on the right.

I would like to moderate this point. Having long logs does not mean that a 4k screen is required to display them. On the contrary, structlog uses colors and padding to make sure that even when a log spans over several lines:

• it is clear where the log starts, where it ends
• it is easy to identify it using the message in bold

See this example from the screenshot:

That being said, I agree that we have to find a compromise between having more information in case we need it, and having less to decrease the noise. I think the custom renderer in the description show how this compromise could look like.

However, I'd like to point out that this compromise exists whether we use structlog or not, but that structlog does help us:

• improve the readability of multi line logs with colors and padding
• tweak this compromise consistently by changing the renderers instead of going through each log to add or remove context.

A few suggestions [...]

I like those, especially having two levels of verbosity that can set with a pytest argument / environment variable. That would give us proper feedback for tweaking the comprise I mentioned earlier. Also, formatting automatically all *_uuid values with the first 8 characters would also help a lot. I updated the description with those suggestions.

It's not entirely clear to me what need you address.

I updated the description with a section about expected improvement. I'd like the discussions with the team to help:

• decide if those points are valid and worth the change
• maybe find more improvements or elaborate on the ones already listed
• identify blocking points or constraints